Record instructions retired alongside time in TIME_TRACE (depends on #928) - #929
Merged
Merged
Conversation
A -tstat sweep is normally run many-ways parallel, and wall clock then measures the machine as much as the code: on the reference server, 120 concurrent jobs spread effective throughput from 1828 M instr/s at p10 to 4724 at p90, so a run at p10 takes 1.71x longer than the median for identical work. Ratios within one run survive that; per-node comparisons between runs do not. Instruction counts do not have that problem. Measured on the same machine, a fixed workload retires 12000031 and 12000032 instructions across seven runs -- a spread of 0.0000%. So each TIME_TRACE node now carries user-space instructions retired as well as elapsed time: [root] (total: 39 ms, avg: 39 ms, cnt: 1, instr: 118 M) Both are kept, deliberately. Part of that 2.6x throughput spread is genuine memory-boundedness rather than contention -- median throughput falls monotonically with peak memory, 4530 M instr/s under 64 MB down to 2672 at 256 MB-1 GB -- and an instructions-only trace would make a node that is slow because it is cache-missing look cheap. Time and instructions together give ns-per-instruction per node, which is what tells those two apart. Reading the counter cheaply Lib/Timer.cpp already opens a PERF_COUNT_HW_INSTRUCTIONS event but reads it with read(PERF_FD), which costs a syscall (~560ns measured) -- fine for the timer thread's 1ms limit check, hopeless for a scope entered ~10^9 times per run. The new Lib/PerfInstructions.hpp mmaps the same fd and reads the counter register directly with rdpmc under the metadata page's seqlock: 8.9ns measured, against 27.5ns for the clock_gettime the profiler already does per scope. rdpmc reads the performance counter of whatever CPU the *caller* runs on, so it is only valid on the thread the event is attached to. Hence the split: ScopedTimer (main thread) takes the fast path, while printPretty -- which runs on timer_thread when a resource limit fires -- credits the still-open scopes using the new Timer::instructionCountAnyThread(), which goes through the fd. Everything degrades to "no measurement" rather than to a wrong number: non-x86, no cap_user_rdpmc, or an event not currently scheduled all yield -1, and the field then prints as "-" so the output format stays unconditional. Two details worth knowing: - reads are ordered so the instruction interval nests inside the time interval (clock first on entry, instructions first on exit), which keeps the cost of the clock read itself out of the instruction count; - [root] is entered during static initialisation, long before the counter exists, so Timer::reinitialise() calls TimeTrace::rebaseInstructionCounters() once the event has been opened and reset. Without it the whole-run total would read 0. instructionCountingAvailable() also refuses to report anything when the PMU is multiplexing this event (time_enabled != time_running), since the kernel then expects counts to be scaled, which would turn them into estimates and destroy the determinism that is the entire point. Verified locally: unit tests 100/100, checks/sanity clean, output format correct. macOS has neither perf_event_open nor user-space PMU access, so the values themselves are NOT verified here -- they read "-". On Linux, check that [root]'s instr matches the independently-obtained "Instructions burned" statistics line (which reads the same event through read()), and that two -al-bounded runs of one problem agree to well under 0.1% per node while their times do not. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
MichaelRawson
approved these changes
Sep 8, 2026
MichaelRawson
left a comment
Contributor
There was a problem hiding this comment.
I will repeat my warning that this kind of DIY profiling may be misleading. Use something like perf record instead. But, with that caveat, this seems like an improvement.
Review feedback on the rdpmc helper: GCC does have an intrinsic for this, and
the __asm__ should be guarded so it cannot reach a compiler that would reject it.
Both hold. gcc/config/i386/ia32intrin.h defines
extern __inline unsigned long long
__attribute__((__gnu_inline__, __always_inline__, __artificial__))
__rdpmc (int __S)
{ return __builtin_ia32_rdpmc (__S); }
and Clang's ia32intrin.h is the same one-liner around the same builtin. Neither
is behind a target pragma or needs an -m flag, unlike the SSE/AVX intrinsics
beside them. Calling the builtin directly keeps <x86intrin.h> -- some 40 000
preprocessed lines -- out of the two translation units that include this header.
The builtin is not subject to common-subexpression elimination, so two reads
still issue two rdpmc instructions, and it stays inside instructionCount()'s
seqlock retry loop; that is what the dropped __volatile__ was for. Verified with
clang 21 targeting x86_64: identical instruction sequence to the asm version,
and the one-read/two-read cases emit one and two rdpmc respectively.
The guard is strictly belt and braces rather than a fix: VAMPIRE_PERF_EXISTS
(Lib/Portability.hpp:22) is 0 unless __linux__ and <linux/perf_event.h>, and this
whole block sits inside it, so MSVC could never see the asm. Adding __GNUC__
states the requirement where the hazard is rather than three files away, and it
is needed just as much by the builtin as it was by the asm.
Not compile-checked against a real GCC: no x86 GCC is available here (the local
MacPorts gcc15 is aarch64-only and ships no x86 intrinsic headers), so the GCC
side rests on the upstream header above. Worth confirming on Linux before merge.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
A -tstat sweep is normally run many-ways parallel, and wall clock then measures the machine as much as the code: on the reference server, 120 concurrent jobs spread effective throughput from 1828 M instr/s at p10 to 4724 at p90, so a run at p10 takes 1.71x longer than the median for identical work. Ratios within one run survive that; per-node comparisons between runs do not.
Instruction counts do not have that problem. Measured on the same machine, a fixed workload retires 12000031 and 12000032 instructions across seven runs -- a spread of 0.0000%.
So each TIME_TRACE node now carries user-space instructions retired as well as elapsed time:
[root] (total: 39 ms, avg: 39 ms, cnt: 1, instr: 118 M)
Both are kept, deliberately. Part of that 2.6x throughput spread is genuine memory-boundedness rather than contention -- median throughput falls monotonically with peak memory, 4530 M instr/s under 64 MB down to 2672 at 256 MB-1 GB -- and an instructions-only trace would make a node that is slow because it is cache-missing look cheap. Time and instructions together give ns-per-instruction per node, which is what tells those two apart.
Reading the counter cheaply
Lib/Timer.cpp already opens a PERF_COUNT_HW_INSTRUCTIONS event but reads it with read(PERF_FD), which costs a syscall (~560ns measured) -- fine for the timer thread's 1ms limit check, hopeless for a scope entered ~10^9 times per run. The new Lib/PerfInstructions.hpp mmaps the same fd and reads the counter register directly with rdpmc under the metadata page's seqlock: 8.9ns measured, against 27.5ns for the clock_gettime the profiler already does per scope.
rdpmc reads the performance counter of whatever CPU the caller runs on, so it is only valid on the thread the event is attached to. Hence the split: ScopedTimer (main thread) takes the fast path, while printPretty -- which runs on timer_thread when a resource limit fires -- credits the still-open scopes using the new Timer::instructionCountAnyThread(), which goes through the fd. Everything degrades to "no measurement" rather than to a wrong number: non-x86, no cap_user_rdpmc, or an event not currently scheduled all yield -1, and the field then prints as "-" so the output format stays unconditional.
Two details worth knowing:
instructionCountingAvailable() also refuses to report anything when the PMU is multiplexing this event (time_enabled != time_running), since the kernel then expects counts to be scaled, which would turn them into estimates and destroy the determinism that is the entire point.
Verified locally: unit tests 100/100, checks/sanity clean, output format correct. macOS has neither perf_event_open nor user-space PMU access, so the values themselves are NOT verified here -- they read "-". On Linux, check that [root]'s instr matches the independently-obtained "Instructions burned" statistics line (which reads the same event through read()), and that two -al-bounded runs of one problem agree to well under 0.1% per node while their times do not.